Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix duplicate log #1661

Open
wants to merge 3 commits into
base: main
Choose a base branch
from
Open

Conversation

qianyun210603
Copy link
Contributor

Fix duplicated log record issue.

Description

Set parent property propagate of QlibLogger to False.

Motivation and Context

If the official python logging module is called somewhere during qlib run, after its call, the same qlib log record will get printed twice with different format, e.g. execute below code snippet

    qlib.init()
    logger = get_module_logger("mytest")
    logger.info("normal")
    logging.debug("directly call logging")
    logger.info("see duplicate")

leads to below result (note the last two lines):

[300088:MainThread](2023-10-05 09:39:03,847) INFO - qlib.Initialization - [config.py:416] - default_conf: client.
[300088:MainThread](2023-10-05 09:39:04,548) INFO - qlib.Initialization - [__init__.py:74] - qlib successfully initialized based on client settings.
[300088:MainThread](2023-10-05 09:39:04,548) INFO - qlib.Initialization - [__init__.py:76] - data_path={'__DEFAULT_FREQ': WindowsPath('G:/qlib_data/cn_data')}
[300088:MainThread](2023-10-05 09:39:04,549) INFO - qlib.mytest - [log_debug.py:8] - normal
[300088:MainThread](2023-10-05 09:39:04,549) INFO - qlib.mytest - [log_debug.py:10] - see duplicate
INFO:qlib.mytest:see duplicate

After some investigation, found that the qlib logger organised with hierarchy <qlib.log.QlibLogger qlib.mytest (INFO)>-<logging.Logger qlib (DEBUG)>-><logging.RootLogger root (WARNING)>, and the log record generated in QlibLogger is propagated to the <logging.Logger qlib (DEBUG)> to be emitted. By default it will also be propagated to the root level, but by default root level has no handler so no emission occurs.
However, direct call of logging will automatically add StreamHandler to the RootLogger, thus we see logger.info("see duplicate") gets emitted twice.
Therefore to fix this we need to truncate the propagation at the second level.

How Has This Been Tested?

  • Pass the test by running: pytest qlib/tests/test_all_pipeline.py under upper directory of qlib.
  • If you are adding a new feature, test on your own test scripts.

Screenshots of Test Results (if appropriate):

  1. Pipeline test:
  2. Your own tests:
    After fix the code snippet gives:
[296660:MainThread](2023-10-05 10:08:41,651) INFO - qlib.Initialization - [config.py:416] - default_conf: client.
[296660:MainThread](2023-10-05 10:08:42,348) INFO - qlib.Initialization - [__init__.py:74] - qlib successfully initialized based on client settings.
[296660:MainThread](2023-10-05 10:08:42,349) INFO - qlib.Initialization - [__init__.py:76] - data_path={'__DEFAULT_FREQ': WindowsPath('G:/qlib_data/cn_data')}
[296660:MainThread](2023-10-05 10:08:42,349) INFO - qlib.mytest - [log_debug.py:8] - normal
[296660:MainThread](2023-10-05 10:08:42,349) INFO - qlib.mytest - [log_debug.py:10] - see duplicate

The duplicate record disappears.

Types of changes

  • Fix bugs
  • Add new feature
  • Update documentation

@github-actions github-actions bot added the waiting for triage Cannot auto-triage, wait for triage. label Oct 5, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
waiting for triage Cannot auto-triage, wait for triage.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

1 participant